Redo frame profiling

We were adding incomplete frame timings to the
profile, which lead to occasional nonsense
numbers. Instead, only add timings to the profile
once we marked them as complete. This also
gives us an opportunity to add the presentation
time as a marker.

diff --git a/gdk/gdkframeclock.c b/gdk/gdkframeclock.c
index 9338a23668fccfe5eff32f2721a0322f84f7077d..4f396bdd939749bcf24a91025fbfd69cab00af5d 100644 (file)
--- a/gdk/gdkframeclock.c
+++ b/gdk/gdkframeclock.c
@@ -87,6 +87,8 @@ enum {
 
 static guint signals[LAST_SIGNAL];
 
+static guint fps_counter;
+
 #define FRAME_HISTORY_MAX_LENGTH 16
 
 struct _GdkFrameClockPrivate
@@ -252,6 +254,11 @@ gdk_frame_clock_init (GdkFrameClock *clock)
 
   priv->frame_counter = -1;
   priv->current = FRAME_HISTORY_MAX_LENGTH - 1;
+
+#ifdef G_ENABLE_DEBUG
+  if (fps_counter == 0)
+    fps_counter = gdk_profiler_define_counter ("fps", "Frames per Second");
+#endif
 }
 
 /**
@@ -645,3 +652,105 @@ _gdk_frame_clock_emit_resume_events (GdkFrameClock *frame_clock)
 {
   g_signal_emit (frame_clock, signals[RESUME_EVENTS], 0);
 }
+
+#ifdef G_ENABLE_DEBUG
+static gint64
+guess_refresh_interval (GdkFrameClock *frame_clock)
+{
+  gint64 interval;
+  gint64 i;
+
+  interval = G_MAXINT64;
+
+  for (i = gdk_frame_clock_get_history_start (frame_clock);
+       i < gdk_frame_clock_get_frame_counter (frame_clock);
+       i++)
+    {
+      GdkFrameTimings *t, *before;
+      gint64 ts, before_ts;
+
+      t = gdk_frame_clock_get_timings (frame_clock, i);
+      before = gdk_frame_clock_get_timings (frame_clock, i - 1);
+      if (t == NULL || before == NULL)
+        continue;
+
+      ts = gdk_frame_timings_get_frame_time (t);
+      before_ts = gdk_frame_timings_get_frame_time (before);
+      if (ts == 0 || before_ts == 0)
+        continue;
+
+      interval = MIN (interval, ts - before_ts);
+    }
+
+  if (interval == G_MAXINT64)
+    return 0;
+
+  return interval;
+}
+
+static double
+frame_clock_get_fps (GdkFrameClock *frame_clock)
+{
+  GdkFrameTimings *start, *end;
+  gint64 start_counter, end_counter;
+  gint64 start_timestamp, end_timestamp;
+  gint64 interval;
+
+  start_counter = gdk_frame_clock_get_history_start (frame_clock);
+  end_counter = gdk_frame_clock_get_frame_counter (frame_clock);
+  start = gdk_frame_clock_get_timings (frame_clock, start_counter);
+  for (end = gdk_frame_clock_get_timings (frame_clock, end_counter);
+       end_counter > start_counter && end != NULL && !gdk_frame_timings_get_complete (end);
+       end = gdk_frame_clock_get_timings (frame_clock, end_counter))
+    end_counter--;
+  if (end_counter - start_counter < 4)
+    return 0.0;
+
+  start_timestamp = gdk_frame_timings_get_presentation_time (start);
+  end_timestamp = gdk_frame_timings_get_presentation_time (end);
+  if (start_timestamp == 0 || end_timestamp == 0)
+    {
+      start_timestamp = gdk_frame_timings_get_frame_time (start);
+      end_timestamp = gdk_frame_timings_get_frame_time (end);
+    }
+  interval = gdk_frame_timings_get_refresh_interval (end);
+  if (interval == 0)
+    {
+      interval = guess_refresh_interval (frame_clock);
+      if (interval == 0)
+        return 0.0;
+    }   
+    
+  return ((double) end_counter - start_counter) * G_USEC_PER_SEC / (end_timestamp - start_timestamp);
+}
+#endif
+
+void
+_gdk_frame_clock_add_timings_to_profiler (GdkFrameClock   *clock,
+                                          GdkFrameTimings *timings)
+{
+#ifdef G_ENABLE_DEBUG
+  gdk_profiler_add_mark (timings->frame_time * 1000,
+                         (timings->frame_end_time - timings->frame_time) * 1000,
+                         "frame", "");
+
+  if (timings->layout_start_time != 0)
+    gdk_profiler_add_mark (timings->layout_start_time * 1000,
+                           (timings->paint_start_time - timings->layout_start_time) * 1000,
+                            "layout", "");
+
+  if (timings->paint_start_time != 0)
+    gdk_profiler_add_mark (timings->paint_start_time * 1000,
+                           (timings->frame_end_time - timings->paint_start_time) * 1000,
+                            "paint", "");
+
+  if (timings->presentation_time != 0)
+    gdk_profiler_add_mark (timings->presentation_time * 1000,
+                           0,
+                           "presentation", "");
+
+  gdk_profiler_set_counter (fps_counter,
+                            timings->frame_end_time * 1000,
+                            frame_clock_get_fps (clock)); 
+#endif
+}

diff --git a/gdk/gdkframeclockidle.c b/gdk/gdkframeclockidle.c
index 8bbdffb68b7ec4105791d143bc4b20d268e3909f..a917176993e5ca16788132ec7533ba417c02c81e 100644 (file)
--- a/gdk/gdkframeclockidle.c
+++ b/gdk/gdkframeclockidle.c
@@ -114,96 +114,6 @@ get_sleep_serial (void)
   return sleep_serial;
 }
 
-static guint fps_counter = 0;
-
-static void
-add_timings_to_profiler (GdkFrameTimings *timings)
-{
-  gdk_profiler_add_mark (timings->frame_time * 1000,
-                         (timings->frame_end_time - timings->frame_time) * 1000,
-                         "frame", "");
-  if (timings->layout_start_time != 0)
-    gdk_profiler_add_mark (timings->layout_start_time * 1000,
-                           (timings->paint_start_time - timings->layout_start_time) * 1000,
-                            "layout", "");
-
-  if (timings->paint_start_time != 0)
-    gdk_profiler_add_mark (timings->paint_start_time * 1000,
-                           (timings->frame_end_time - timings->paint_start_time) * 1000,
-                            "paint", "");
-}
-
-static gint64
-guess_refresh_interval (GdkFrameClock *frame_clock)
-{
-  gint64 interval;
-  gint64 i;
-
-  interval = G_MAXINT64;
-
-  for (i = gdk_frame_clock_get_history_start (frame_clock);
-       i < gdk_frame_clock_get_frame_counter (frame_clock);
-       i++)
-    {
-      GdkFrameTimings *t, *before;
-      gint64 ts, before_ts;
-
-      t = gdk_frame_clock_get_timings (frame_clock, i);
-      before = gdk_frame_clock_get_timings (frame_clock, i - 1);
-      if (t == NULL || before == NULL)
-        continue;
-
-      ts = gdk_frame_timings_get_frame_time (t);
-      before_ts = gdk_frame_timings_get_frame_time (before);
-      if (ts == 0 || before_ts == 0)
-        continue;
-
-      interval = MIN (interval, ts - before_ts);
-    }
-
-  if (interval == G_MAXINT64)
-    return 0;
-
-  return interval;
-}
-
-static double
-frame_clock_get_fps (GdkFrameClock *frame_clock)
-{
-  GdkFrameTimings *start, *end;
-  gint64 start_counter, end_counter;
-  gint64 start_timestamp, end_timestamp;
-  gint64 interval;
-
-  start_counter = gdk_frame_clock_get_history_start (frame_clock);
-  end_counter = gdk_frame_clock_get_frame_counter (frame_clock);
-  start = gdk_frame_clock_get_timings (frame_clock, start_counter);
-  for (end = gdk_frame_clock_get_timings (frame_clock, end_counter);
-       end_counter > start_counter && end != NULL && !gdk_frame_timings_get_complete (end);
-       end = gdk_frame_clock_get_timings (frame_clock, end_counter))
-    end_counter--;
-  if (end_counter - start_counter < 4)
-    return 0.0;
-
-  start_timestamp = gdk_frame_timings_get_presentation_time (start);
-  end_timestamp = gdk_frame_timings_get_presentation_time (end);
-  if (start_timestamp == 0 || end_timestamp == 0)
-    {
-      start_timestamp = gdk_frame_timings_get_frame_time (start);
-      end_timestamp = gdk_frame_timings_get_frame_time (end);
-    }
-
-  interval = gdk_frame_timings_get_refresh_interval (end);
-  if (interval == 0)
-    {
-      interval = guess_refresh_interval (frame_clock);
-      if (interval == 0)
-        return 0.0;
-    }
-
-  return ((double) end_counter - start_counter) * G_USEC_PER_SEC / (end_timestamp - start_timestamp);
-}
-
 static void
 gdk_frame_clock_idle_init (GdkFrameClockIdle *frame_clock_idle)
 {
@@ -214,11 +124,6 @@ gdk_frame_clock_idle_init (GdkFrameClockIdle *frame_clock_idle)
 
   priv->frame_time = g_get_monotonic_time (); /* more sane than zero */
   priv->freeze_count = 0;
-
-#ifdef G_ENABLE_DEBUG
-  if (fps_counter == 0)
-    fps_counter = gdk_profiler_define_counter ("fps", "Frames per Second");
-#endif
 }
 
 static void
@@ -570,23 +475,6 @@ gdk_frame_clock_paint_idle (void *data)
         }
     }
 
-#ifdef G_ENABLE_DEBUG
-  if (gdk_profiler_is_running ())
-    {
-      if (timings)
-        {
-          add_timings_to_profiler (timings);
-          gdk_profiler_set_counter (fps_counter, timings->frame_end_time * 1000, frame_clock_get_fps (clock)); 
-        }
-    }
-
-  if (GDK_DEBUG_CHECK (FRAMES))
-    {
-      if (timings && timings->complete)
-        _gdk_frame_clock_debug_print_timings (clock, timings);
-    }
-#endif /* G_ENABLE_DEBUG */
-
   if (priv->requested & GDK_FRAME_CLOCK_PHASE_RESUME_EVENTS)
     {
       priv->requested &= ~GDK_FRAME_CLOCK_PHASE_RESUME_EVENTS;

diff --git a/gdk/gdkframeclockprivate.h b/gdk/gdkframeclockprivate.h
index 17e06dfcf765396f10d9e51fc071b5bb832e6370..17d063b4344b143c7537981d6e2e62ff37c10e40 100644 (file)
--- a/gdk/gdkframeclockprivate.h
+++ b/gdk/gdkframeclockprivate.h
@@ -28,6 +28,7 @@
 #define __GDK_FRAME_CLOCK_PRIVATE_H__
 
 #include <gdk/gdkframeclock.h>
+#include <gdk/gdkprofilerprivate.h>
 
 G_BEGIN_DECLS
 
@@ -110,6 +111,8 @@ void _gdk_frame_clock_thaw   (GdkFrameClock *clock);
 void _gdk_frame_clock_begin_frame         (GdkFrameClock   *clock);
 void _gdk_frame_clock_debug_print_timings (GdkFrameClock   *clock,
                                            GdkFrameTimings *timings);
+void _gdk_frame_clock_add_timings_to_profiler (GdkFrameClock *frame_clock,
+                                               GdkFrameTimings *timings);
 
 GdkFrameTimings *_gdk_frame_timings_new   (gint64           frame_counter);
 gboolean         _gdk_frame_timings_steal (GdkFrameTimings *timings,

diff --git a/gdk/wayland/gdksurface-wayland.c b/gdk/wayland/gdksurface-wayland.c
index 7af011b814fd534b404186c18fbdffe138526b8a..f92a8ce2adf752d204fd5f7318b7bb4e7d7dd7fa 100644 (file)
--- a/gdk/wayland/gdksurface-wayland.c
+++ b/gdk/wayland/gdksurface-wayland.c
@@ -423,6 +423,9 @@ frame_callback (void               *data,
 #ifdef G_ENABLE_DEBUG
   if ((_gdk_debug_flags & GDK_DEBUG_FRAMES) != 0)
     _gdk_frame_clock_debug_print_timings (clock, timings);
+
+  if (gdk_profiler_is_running ())
+    _gdk_frame_clock_add_timings_to_profiler (clock, timings);
 #endif
 }
 

diff --git a/gdk/x11/gdkdisplay-x11.c b/gdk/x11/gdkdisplay-x11.c
index ca1237e70307722b41b8f834fb749dad223b3351..dc0f017afd9ab7a9dcbb4a6ecf9b57a9045ec8e2 100644 (file)
--- a/gdk/x11/gdkdisplay-x11.c
+++ b/gdk/x11/gdkdisplay-x11.c
@@ -1283,6 +1283,9 @@ _gdk_wm_protocols_filter (const XEvent *xevent,
 #ifdef G_ENABLE_DEBUG
               if (GDK_DISPLAY_DEBUG_CHECK (display, FRAMES))
                 _gdk_frame_clock_debug_print_timings (clock, timings);
+
+              if (gdk_profiler_is_running ())
+                _gdk_frame_clock_add_timings_to_profiler (clock, timings);
 #endif /* G_ENABLE_DEBUG */
             }
         }